**** dT 0.000 * top TEST ../../../../bin/varnishtest/tests/c00121.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:44771 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub **** top extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../.. **** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests **** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866 **** top macro def vtcid=vtc.1396291.1d444866 ** top === varnishtest "Abstract UDS backend: change path, drop poll" * top VTEST Abstract UDS backend: change path, drop poll ** top === feature abstract_uds ** top === server s1 -listen "@${vtcid}.s1.sock" { ** s1 Starting server **** s1 macro def s1_addr=0.0.0.0 **** s1 macro def s1_port=0 **** s1 macro def s1_sock=@vtc.1396291.1d444866.s1.sock * s1 Listen on @vtc.1396291.1d444866.s1.sock ** top === server s2 -listen "@${vtcid}.s2.sock" { ** s2 Starting server **** s2 macro def s2_addr=0.0.0.0 **** s2 macro def s2_port=0 **** s2 macro def s2_sock=@vtc.1396291.1d444866.s2.sock * s2 Listen on @vtc.1396291.1d444866.s2.sock ** top === varnish v1 -arg "-a @${vtcid}.v1.sock" -vcl { **** dT 0.005 ** s2 Started on @vtc.1396291.1d444866.s2.sock (1 iterations) ** s1 Started on @vtc.1396291.1d444866.s1.sock (1 iterations) **** dT 0.015 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -M '127.0.0.1 41093' -P /home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -a @vtc.1396291.1d444866.v1.sock *** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -M '127.0.0.1 41093' -P /home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs -a @vtc.1396291.1d444866.v1.sock **** dT 0.016 *** v1 PID: 1396311 **** v1 macro def v1_pid=1396311 **** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.1396291.1d444866/v1 **** dT 0.019 *** v1 debug|Info: Working directory not mounted on tmpfs partition *** v1 debug| **** dT 0.039 *** v1 debug|Debug: Version: varnish-trunk revision 680057e61ba5f49202ca2530979f9e9a1a2fedbb *** v1 debug|Debug: Platform: Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v1 debug|200 329 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision 680057e61ba5f49202ca2530979f9e9a1a2fedbb *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.140 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 9 *** v1 CLI RX 107 **** v1 CLI RX|qggnckrqkajlwhrpmlhlyzslmzembohy **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 38055284f3065f209c2ef83e37b6fe1d64046ff9d1c953d4a2864a707b50195a **** dT 0.145 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision 680057e61ba5f49202ca2530979f9e9a1a2fedbb **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tprobe default { **** v1 CLI TX|\t\t.window = 8; **** v1 CLI TX|\t\t.initial = 7; **** v1 CLI TX|\t\t.threshold = 8; **** v1 CLI TX|\t\t.interval = 0.1s; **** v1 CLI TX|\t} **** v1 CLI TX|\tbackend s1 { **** v1 CLI TX|\t\t.path = "@vtc.1396291.1d444866.s2.sock"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.251 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.352 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.452 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.459 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.531 *** v1 debug|Debug: Child (1396324) Started **** dT 0.553 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.584 *** v1 debug|Child launched OK **** dT 0.585 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 0.587 *** s2 accepted fd 6 0.0.0.0 0 ** s2 === non_fatal ** s2 === timeout 3 ** s2 === loop 40 { **** s2 Loop #0 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting *** v1 debug|Info: Child (1396324) said Child starts **** dT 0.651 *** v1 CLI RX 200 **** v1 CLI RX|a0 @vtc.1396291.1d444866.v1.sock - **** v1 CLI TX|debug.xid 1000 **** dT 0.654 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1742239787.851221/vgc.so 1auto **** v1 vsl| 0 Backend_health - s1 Went sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1742239787.851221/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=@vtc.1396291.1d444866.v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=@vtc.1396291.1d444866.v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=@vtc.1396291.1d444866.v1.sock **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=@vtc.1396291.1d444866.v1.sock **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 Backend_health - s1 Went healthy --U-X-RH 8 8 8 0.002292 0.000573 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 35 a0 @vtc.1396291.1d444866.v1.sock - **** dT 0.695 *** s2 Accepted socket fd is 6 **** s2 Loop #1 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 0.715 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 0.755 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005163 0.001721 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** dT 0.766 *** v1 CLI RX 200 **** v1 CLI RX|a0 @vtc.1396291.1d444866.v1.sock - ** v1 Listen on 0.0.0.0 0 **** v1 macro def v1_addr=0.0.0.0 **** v1 macro def v1_port=0 **** v1 macro def v1_sock=@vtc.1396291.1d444866.v1.sock **** v1 macro def v1_a0_addr=0.0.0.0 **** v1 macro def v1_a0_port=0 **** v1 macro def v1_a0_sock=@vtc.1396291.1d444866.v1.sock ** top === delay 1 *** top delaying 1 second(s) **** dT 0.801 *** s2 Accepted socket fd is 6 **** s2 Loop #2 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 0.858 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 35 a0 @vtc.1396291.1d444866.v1.sock - **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.004497 0.002415 "HTTP/1.1 200 OK" **** dT 0.909 *** s2 Accepted socket fd is 6 **** s2 Loop #3 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 0.960 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005245 0.003122 "HTTP/1.1 200 OK" **** dT 1.024 *** s2 Accepted socket fd is 6 **** s2 Loop #4 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.068 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.004968 0.003584 "HTTP/1.1 200 OK" **** dT 1.129 *** s2 Accepted socket fd is 6 **** s2 Loop #5 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.169 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005100 0.003963 "HTTP/1.1 200 OK" **** dT 1.241 *** s2 Accepted socket fd is 6 **** s2 Loop #6 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:48 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.269 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005155 0.004261 "HTTP/1.1 200 OK" **** dT 1.396 *** s2 Accepted socket fd is 6 **** s2 Loop #7 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.474 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.051176 0.015990 "HTTP/1.1 200 OK" **** dT 1.498 *** s2 Accepted socket fd is 6 **** s2 Loop #8 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.578 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.000127 0.012024 "HTTP/1.1 200 OK" **** dT 1.607 *** s2 Accepted socket fd is 6 **** s2 Loop #9 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.683 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005319 0.010348 "HTTP/1.1 200 OK" **** dT 1.716 *** s2 Accepted socket fd is 6 **** s2 Loop #10 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.767 ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl2 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tprobe default { **** v1 CLI TX|\t\t.window = 8; **** v1 CLI TX|\t\t.initial = 7; **** v1 CLI TX|\t\t.threshold = 8; **** v1 CLI TX|\t\t.interval = 0.1s; **** v1 CLI TX|\t} **** v1 CLI TX|\tbackend s1 { **** v1 CLI TX|\t\t.path = "@vtc.1396291.1d444866.s1.sock"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 1.783 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.004756 0.008950 "HTTP/1.1 200 OK" **** dT 1.832 *** s2 Accepted socket fd is 6 **** s2 Loop #11 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 1.888 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005396 0.008061 "HTTP/1.1 200 OK" **** dT 1.960 *** s2 Accepted socket fd is 6 **** s2 Loop #12 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 2.092 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.080882 0.026266 "HTTP/1.1 200 OK" **** dT 2.145 *** s2 Accepted socket fd is 6 **** s2 Loop #13 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 2.180 *** s1 accepted fd 7 0.0.0.0 0 ** s1 === non_fatal ** s1 === timeout 3 ** s1 === loop 40 { **** s1 Loop #0 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 0.0.0.0\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 52 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 0.0.0.0 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === accept **** s1 Accepting **** dT 2.186 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl2 **** dT 2.187 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active **** v1 CLI TX|vcl.use vcl2 **** dT 2.196 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.005520 0.021080 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1742239789.469696/vgc.so 1auto **** v1 vsl| 0 Backend_health - s1 Went sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1742239789.469696/vgc.so" as "vcl2" **** v1 vsl| 0 Backend_health - s1 Went healthy --U-X-RH 8 8 8 0.008167 0.002042 "HTTP/1.1 200 OK" **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 2.261 *** v1 CLI RX 200 ** v1 CLI 200 **** v1 CLI TX|vcl.discard vcl1 **** dT 2.288 *** s1 Accepted socket fd is 7 **** s1 Loop #1 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 0.0.0.0\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 52 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 0.0.0.0 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === accept **** s1 Accepting **** dT 2.294 *** s2 Accepted socket fd is 6 **** s2 Loop #14 ** s2 === rxreq **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 0.0.0.0\r **** s2 rxhdr|Connection: close\r **** s2 rxhdr|\r **** s2 rxhdrlen = 52 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 0.0.0.0 **** s2 http[ 4] |Connection: close **** s2 bodylen = 0 ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Mon, 17 Mar 2025 19:29:49 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r ** s2 === accept **** s2 Accepting **** dT 2.296 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.006846 0.003243 "HTTP/1.1 200 OK" **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.032531 0.023943 "HTTP/1.1 200 OK" **** dT 2.343 *** v1 CLI RX 200 ** v1 CLI 200 ** top === delay 1 *** top delaying 1 second(s) **** dT 2.400 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0cold **** v1 vsl| 0 Backend_health - s1 Went sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.discard vcl1 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 2.423 *** s1 Accepted socket fd is 7 **** s1 Loop #2 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 0.0.0.0\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 52 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 0.0.0.0 **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Mon, 17 Mar 2025 19:29:50 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === accept **** s1 Accepting **** dT 2.501 **** v1 vsl| 0 Backend_health - s1 Still healthy --U-X-RH 8 8 8 0.000804 0.002633 "HTTP/1.1 200 OK" **** dT 3.348 ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl3 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tbackend s1 { **** v1 CLI TX|\t\t.path = "@vtc.1396291.1d444866.s1.sock"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 4.068 *** v1 CLI RX 200 **** v1 CLI TX|vcl.use vcl3 **** dT 4.078 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl3' now active **** v1 CLI TX|vcl.use vcl3 **** dT 4.134 **** v1 vsl| 0 CLI - Rd vcl.load vcl3 vcl_vcl3.1742239791.045466/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl3.1742239791.045466/vgc.so" as "vcl3" **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1742239791 1.0 **** v1 vsl| 0 CLI - Rd vcl.use vcl3 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 4.139 *** v1 CLI RX 200 ** v1 CLI 200 **** v1 CLI TX|vcl.discard vcl2 **** dT 4.604 *** v1 CLI RX 200 ** v1 CLI 200 ** top === delay 1 *** top delaying 1 second(s) **** dT 4.652 **** v1 vsl| 0 CLI - Rd vcl.state vcl2 0cold **** v1 vsl| 0 Backend_health - s1 Went sick -------H 7 8 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.discard vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 5.606 ** top === varnish v1 -cliok "vcl.list" **** v1 CLI TX|vcl.list **** dT 5.652 *** v1 CLI RX 200 **** v1 CLI RX|active auto warm 0 vcl3 ** v1 CLI 200 ** top === varnish v1 -cliok "backend.list -p" **** v1 CLI TX|backend.list -p **** dT 5.671 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 32 active auto warm 0 vcl3 **** dT 5.704 *** v1 CLI RX 200 **** v1 CLI RX|Backend name Admin Probe Health Last change **** v1 CLI RX|vcl3.s1 healthy 0/0 healthy Mon, 17 Mar 2025 19:29:51 GMT ** v1 CLI 200 ** top === server s1 -break { ** s1 Breaking for server **** dT 5.709 ** s1 Starting server **** s1 macro def s1_addr=0.0.0.0 **** s1 macro def s1_port=0 **** s1 macro def s1_sock=@vtc.1396291.1d444866.s1.sock * s1 Listen on @vtc.1396291.1d444866.s1.sock ** top === delay 1 *** top delaying 1 second(s) **** dT 5.713 ** s1 Started on @vtc.1396291.1d444866.s1.sock (1 iterations) **** dT 5.771 **** v1 vsl| 0 CLI - Rd backend.list -p **** v1 vsl| 0 CLI - Wr 200 128 Backend name Admin Probe Health Last change vcl3.s1 healthy 0/0 healthy Mon, 17 Mar 2025 19:29:51 GMT **** dT 5.906 *** s1 accepted fd 7 0.0.0.0 0 ** s1 === rxreq **** s1 rxhdrlen = 0 ---- s1 HTTP header is incomplete **** dT 6.710 * top RESETTING after ../../../../bin/varnishtest/tests/c00121.vtc ** s1 Waiting for server (4/-1) ** s2 Waiting for server (5/-1) **** dT 6.762 ** v1 Wait **** v1 CLI TX|panic.show **** dT 6.818 *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared *** v1 debug|Info: manager stopping child *** v1 debug|Debug: Stopping Child **** dT 6.889 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 6.919 *** v1 debug|Info: Child (1396324) said Child dies **** dT 7.026 *** v1 debug|Info: Child (1396324) ended *** v1 debug|Debug: Child cleanup complete *** v1 debug|Info: manager dies **** v1 STDOUT EOF **** dT 7.096 ** v1 WAIT4 pid=1396311 status=0x0000 (user 0.662209 sys 0.074393) * top TEST ../../../../bin/varnishtest/tests/c00121.vtc FAILED # top TEST ../../../../bin/varnishtest/tests/c00121.vtc FAILED (7.099) exit=2 FAIL tests/c00121.vtc (exit status: 2)